fluentdでapacheのログに時間が出力されなくて苦労したので解決策と原理をまとめてみた

こんにちは、臼田です。

最近fluentdを使い始めたのですが、apacheのログに時間を含めて出力できなかったので対処法と周辺情報をまとめてみます。

やりたいこと

構成としては単純にEC2のapache access_logをfluentdを利用してS3に出力する形です。

目的としてはログの永続化で、使用目的は何かあったらAmazon Athenaで分析できればいいかな、くらいです。

上記AWS環境の構築については説明を省きます。リソースの作成やIAM Roleの設定等は済んでいる前提で進みます。

fluentdのインストールについては公式ドキュメントを参照してください。(最近リンクが変わった模様)

時間が出力されない設定

まず最初に私がハマった時間が出力されない設定を共有します。

# read apache logs
<source>
  @type tail
  <parse>
    @type apache2
  </parse>
  path /var/log/httpd/access_log
  pos_file /var/log/td-agent/tmp/access.log.pos
  tag apache.access
</source>

# send to S3
<match apache.access>
  @type s3
  s3_bucket mybucket
  path access_log/
  s3_region ap-northeast-1
  time_slice_format %Y/%m/%d
  s3_object_key_format %{path}%{time_slice}/access_%{index}.%{file_extension}
  <format>
    @type json
  </format>
  <buffer>
    @type file
    path /var/log/td-agent/s3
    timekey 30
    timekey_wait 30
    timekey_use_utc true
  </buffer>
</match>

中身としてはapacheのログを@type apache2でパースしてjsonフォーマットでS3に出している形です。

ちなみに30秒おきに出力するようにしていますが、これはEC2がターミネートするなどでログが消える範囲を極力減らすために短くしています。

今回のケースでは使っていませんが、AutoScaling環境などでは縮退時にログが消えてしまうと困るのでこのくらいの間隔がいいようです。

また、AutoScalingの場合にはインスタンスIDをファイル名やログの中に入れておくと有効な場面もあるようです。

td-agent.confの書き方は検索するといっぱい出てくるかと思いますが、バージョンが古かったり(現バージョンはtd-agent3, v1.0)必要な記述なのかわからなかったりすることも多いので、公式ドキュメントを参照するといいです。目的別の参考設定もあり、apacheのログをS3に出す設定もあったので今回は最初これを参考にしました。バージョンが変わってparseやformatの書き方が変わって非推奨になっているので、古い記事から持ってきた設定が動いても正しい書き方か確認したほうがいいです。

余談が長くなりましたが、上記設定ではS3に出力されたログが下記のようになってしまいます。

{"host":"10.0.1.100","user":null,"method":"GET","path":"/","code":301,"size":229,"referer":null,"agent":"ELB-HealthChecker/2.0"}

はい、時間が出力されていません。

ちなみにformatを外すと下記のように時間が入りますが、求めているのはこれではないです。あくまでjsonの中に時間がほしいですよね。

2019-05-10T21:03:39+09:00 apache.access {"host":"10.0.1.100","user":null,"method":"GET","path":"/","code":301,"size":229,"referer":null,"agent":"ELB-HealthChecker/2.0"}

ちなみにjson以外のフォーマット(ltsv等)でも同様な動きをするので悩まされました。

原因と解決策

timeの扱いについて

この原因を理解するためには、fluentdの中で時間がどのように扱われるかを理解する必要があります。

こちらに情報がありますが、sourceからイベントがルーティングされる際には3つのエンティティに分類されていて、tag, time and recordとなっています。通常ログはすべてrecordに含まれますが、timeだけ扱いが異なります。

そして次に今回使っているapache2パーサのドキュメントを確認します。こちらには下記のようにあり、アクセスログのevent timeをtimeとして扱うと書かれています。

time is used for the event time.

そして、その下に書かれている例にはrecordにtimeが含まれていません。

というわけで、原因としてはsource内でパースする段階でログの中から時間の情報が抜かれているため、出力されたログにも時間が書かれていないということでした。

timeをrecordに含める方法

もちろん、record内にtimeが含まれていないと困ることもあるので、パーサセクションのドキュメントに対処法の記載があります。

keep_time_key (bool) (optional): If true, keep time field in the record. - Default: false

keep_time_keyの設定でrecordにtimeを残すことができるようになっていますが、デフォルトfalseなのでこれをtrueにして解決です。

最終的な設定は下記のようになりました。

# read apache logs
<source>
  @type tail
  <parse>
    @type apache2
    keep_time_key true
  </parse>
  path /var/log/httpd/access_log
  pos_file /var/log/td-agent/tmp/access.log.pos
  tag apache.access
</source>

# send to S3
<match apache.access>
  @type s3
  s3_bucket mybucket
  path access_log/
  s3_region ap-northeast-1
  time_slice_format %Y/%m/%d
  s3_object_key_format %{path}%{time_slice}/access_%{index}.%{file_extension}
  <format>
    @type json
  </format>
  <buffer>
    @type file
    path /var/log/td-agent/s3
    timekey 30
    timekey_wait 30
    timekey_use_utc true
  </buffer>
</match>

parseディレクティブにkeep_time_key trueを追記すればOKです。

出力結果は下記のようになりました。

{"host":"10.0.1.100","user":null,"method":"GET","path":"/","code":301,"size":229,"referer":null,"agent":"ELB-HealthChecker/2.0","time":"16/May/2019:22:47:44 +0900"}

まとめ

解決策としては単に1行追加するだけで良かったのですが、fluentdのことを理解するための情報が盛り沢山だったので一緒にまとめてみました。

公式ドキュメントを辿るのはよくわかっていないうちは辛いところもあるかと思いますが、この記事で少しでも理解が深まれば幸いです。理解が深まればより適切に正しい情報にありつけると思います。

それでは、よいロギングライフを！